slf4j-apiのバージョンが1.8系にアップグレードされてログが出力されなくなった

ある日、気がついたらslf4j-apiのバージョンが1.8系になり、ログが出力されなりました。その際の対応メモです。

結論

先に結論を書いておきます。ログが出力されなくなったのはアプリケーションで利用しているライブラリの中に、slf4j-apiのバージョンを特定のバージョン以上としているライブラリがあったためでした。。そのため、build.gradleのdependencieでそのライブラリをexcludeすることで問題を解消できました。

実行環境

• Java 1.8
• Gradle 2.12
• Tomcat 8

エラー調査

ログが出力されなくなったのでTomcatのcatalina.outを確認した所、以下のログが出力されていました。

SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#noProviders for further details.
SLF4J: Class path contains SLF4J bindings targeting slf4j-api versions prior to 1.8.
SLF4J: Ignoring binding found at [jar:file:/var/lib/tomcat8/webapps/ROOT/WEB-INF/lib/logback-classic-1.1.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#ignoredBindings for an explanation.

親切にもエラー内容と共にURLも書かれていました。

• https://www.slf4j.org/codes.html#noProviders
• http://www.slf4j.org/codes.html#ignoredBindings

URLのページを参照した所、SLF4JはJigsaw (Java 9) への対応のため、1.8からServiceLoaderを利用する実装に切り替えたとのことでした。そのため、1.7の形式に対応した実装があっても無視するとのことでした。

しかし、手元のbuild.gradleのslf4j-apiのバージョンは1.7.13でした。。

	compile "org.slf4j:slf4j-api:1.7.13"

そこで./gradlew app:dependenciesでライブラリの依存関係を確認してみた所、確かに1.8.0-alpha2になっていました。

$ ./gradlew app:dependencies
...
+--- org.slf4j:slf4j-api:1.7.13 -> 1.8.0-alpha2
...

おかしいなーと思い、他のライブラリも調べていたら犯人が分かりました。spring-data-mirageを利用していたのですが、このライブラリが犯人でした。

$ ./gradlew app:dependencies
...
|    +--- org.springframework.data:spring-data-mirage:0.3.3.RELEASE
|    |    +--- org.slf4j:slf4j-api:[1.6.2,) -> 1.8.0-alpha2
...

対応

spring-data-mirageが原因だったので、spring-data-mirageについてはdependenciesにおいてslf4j-apiをexcludeするようにしました。

	compile ("org.springframework.data:spring-data-mirage:0.3.3.RELEASE") {
		exclude group: "org.slf4j", module: "slf4j-api"
	}

変更後に./gradlew app:dependenciesでライブラリの依存関係を確認してみた所、1.7.21になっていました。

$ ./gradlew app:dependencies
...
+--- org.slf4j:slf4j-api:1.7.13 -> 1.7.21
...

とりあえず1.7系に下げられたので問題なしと判断し、再度Tomcatにデプロイしたらログが出力されるようになりました。catalina.outもエラーがなくなりlogback.xmlが読み込まれるログに変わっていました。

11:24:18,371 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [/etc/app/logback.xml] at [file:/etc/app/logback.xml]
11:24:18,427 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
11:24:18,439 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds
11:24:18,443 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[/etc/app/logback.xml]] every 30 seconds.
11:24:18,444 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
11:24:18,464 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Adding LoggerContextListener of type [ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
11:24:18,597 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3ad7350a - Setting level of jul logger [org.apache.catalina.core.ContainerBase.[Catalina].[localhost]] to null
11:24:18,598 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3ad7350a - Propagating DEBUG level on Logger[ROOT] onto the JUL framework
11:24:18,598 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Starting LoggerContextListener

最後に

ログ周りの設定を一切いじっていないのに急にログが出なくなって焦りました。今後はdependenciesを確認して意図しないアップグレードが発生しないように気をつけたいと思いました。参考になれば幸いです。